#!/usr/bin/env python

"""
__author__ = Zdenek Maxa

fdtcp project (aimed at integration of FDT and phedex)

https://twiki.cern.ch/twiki/bin/view/Main/PhEDExFDTIntegration
http://code.google.com/p/phedex-fdt/

FDT service wrapper (FDT daemon - fdtd)
PYRO daemon
Invokes FDT Java client / server party

FDT Java instances are created as new processes rather than threads which
    can't be killed if necessary, e.g. when transfer hangs.

TODO:
ServiceShutdownBySignalForced is not implemented. When required, it would
check if there is a transfer in progress and normal stop will not stop
the daemon whereas stop-force will interrupt the current transfers.

"""


import os
import sys
sys.path.append("/usr/lib/python2.4/site-packages")
import re
import signal
import logging
import time
import threading
import datetime
from threading import Lock
try:
    # force loading fdtcplib.__init__.py (see comment in this file related
    # to PYRO_STORAGE env. variable setting) - must be before first PYRO import
    import fdtcplib
    from ApMon import apmon
    from M2Crypto import SSL # just test dependencies
    import Pyro
    import Pyro.core
    from Pyro.errors import PyroError
    from fdtcplib.utils.Executor import Executor, ExecutorException
    from fdtcplib.utils.Config import Config
    from fdtcplib.utils.Logger import Logger
    from fdtcplib.utils.utils import getHostName
    from fdtcplib.common.actions import Result
    from fdtcplib.common.errors import ServiceShutdownBySignal, ServiceShutdownBySignalForced
    from fdtcplib.common.errors import FDTDException, AuthServiceException, PortReservationException
    from fdtcplib.utils.Config import ConfigurationException
except ImportError, ex:
    print "Can't import dependency modules: %s" % ex
    sys.exit(1)

    


class FDTDService(Pyro.core.ObjBase):
    """PYRO service invoked remotely (PYRO daemon)
       Have only very simplistic class - it's exposed to calls from network. 
    """
    
    def __init__(self, logger, conf, apMon, fdtd):
        """Service / daemon has to have reference to the FDT daemon
           object (fdtd) because of administrative actions such as clean up
           of running processes initiated by the remote fdtcp client.
        """
        # this logger is the main daemon (fdtd) logger, if configured
        # each transfer request (which consists of multiple sub-request
        # (network calls)) can be logged into a separate file
        self.logger = logger
        self.conf = conf
        self.apMon = apMon
        self.fdtd = fdtd
        Pyro.core.ObjBase.__init__(self)
        self._stopFlag = False


    
    def _handleServiceStopped(self):
        m = "%s stopped or is being shutdown ..." % self.__class__.__name__
        self.logger.error(m)
        raise PyroError(m)

    
    
    def service(self, action):
        self.logger.debug(60 * '-')
        m = "Request received: %s " % action
        
        # should use separate, transfer request related log files?
        # logs sub-calls belonging to the same transfer will be appended 
        transferSeparateLogFile = self.conf.get("transferSeparateLogFile")
        if transferSeparateLogFile:
            logFile = "/tmp/fdtd-transfer-%s.log" % action.id
            logger = Logger(name = "transfer", logFile = logFile, level = self.conf.get("debug"))
            logger.debug(m)
            self.logger.debug("%s logging separately into file '%s" % (m, logFile))
        else:
            # if not, use the main logger
            logger = self.logger
            logger.debug(m)

        if self._stopFlag:
            self._handleServiceStopped()
        
        # this performs the request from the remote client
        try:
            result = action.execute(conf = self.conf, caller = self.fdtd,
                                    apMon = self.apMon, logger = logger)
            return result
        finally:
            # close logger only in case of separate logging
            if transferSeparateLogFile:
                logger.close()
                        
    
    
    def setStop(self):
        """TODO: should be secured so that it is not called from outside ..."""
        self._stopFlag = True        
        self.logger.debug("%s stop flag set to True ..." % self.__class__.__name__)

    


class FDTD(object):
    """FDTD - daemon object,
       wrapper object to PYRO services,
       keeps track of associated running processes.
    """
    
    _name = None
    
    def __init__(self, conf, apMon, logger):
        self._name = self.__class__.__name__        
        self.conf = conf
        self.apMon = apMon # MonALISA ApMon monitoring instance
        self.logger = logger
        self.logger.debug("Creating instance of %s ..." % self._name)

        # tracking ports occupied by already started FTD Java servers
        # ports are release once the FDT server finishes or is killed        
        try:
            portRangeStr = self.conf.get("portRangeFDTServer")
            portMin, portMax = [int(i) for i in portRangeStr.split(',')]
        except (ValueError, IndexError), ex:
            raise FDTDException("Incorrect format of port range definition: "
                                "'%s', reason: %s" % (portRangeStr, ex))
        # range of all possible ports reserved for FDT Java    
        self._portRange = range(portMin, portMax + 1)
        # will be secured by lock, mutex access to port reservation / releasing
        self._portsTaken = set()
        self._portsTakenLock = threading.Lock()
                
        # dictionary of currently running processes spawned from the PYRO service
        # used to query status, clean up (terminate, kill) when shutting down
        # key is id of the ExecutorAction
        # this dictionary needs exclusive access
        self._executors = {}
        self._executorsLock = Lock()
        
        try:
            port = int(self.conf.get("port"))
        except (ValueError, TypeError), ex:
            raise FDTDException("Can't start %s, wrong port, reason: %s" % (self._name, ex))
                
        host = self.conf.get("hostname") or getHostName()
        
        # multiple signals may be used later for stop, stop-force, etc
        signal.signal(signal.SIGHUP, self._signalHandler)
        signal.signal(signal.SIGTERM, self._signalHandler)
        signal.signal(signal.SIGUSR1, self._signalHandler) 
        
        self._initPYRO(host, port)
        self.service = FDTDService(self.logger, self.conf, self.apMon, self)
        
        self.logger.info("%s daemon object initialised." % self._name)


        
    def _initPYRO(self, host, port):
        """Initialise the PYRO service, start PYRO daemon."""
        Pyro.core.initServer()
        self.logger.debug("Trying to bind to '%s:%s' ..." % (host, port))
        self.pyroDaemon = Pyro.core.Daemon(host = host, port = port)
        self.logger.info("PYRO service is running on %s:%s" %
                         (self.pyroDaemon.hostname, self.pyroDaemon.port))
    
        # want the exact port, if another one was selected, stop
        if self.pyroDaemon.port != port:
            self.pyroDaemon.shutdown(True)
            m = "PYRO service could not use desired port %s, exit." % port
            raise FDTDException(m)

        
        
    def getFreePort(self):
        """Port management method - reserve a free port in a synchronized fashion."""
        self._portsTakenLock.acquire(True) # block
        for port in self._portRange:
            if port not in self._portsTaken:
                break
        else:
            self._portsTakenLock.release()
            raise PortReservationException("No free port to reserve. %s ports "
                                           "taken." % len(self._portsTaken))
        self._portsTaken.add(port)
        self._portsTakenLock.release()
        self.logger.debug("Port '%s' is now reserved." % port)
        return port



    def releasePort(self, port):
        """Port management method - release a port in a synchronized fashion."""
        self._portsTakenLock.acquire(True)
        try:
            try:
                self._portsTaken.remove(port)
            except KeyError:
                self.logger.error("Trying to release a port which has not been reserved (%s)." % port)
        finally:
            self._portsTakenLock.release()
            self.logger.debug("Port '%s' released." % port)

        

    def addExecutor(self, executor):
        # when logging, use the request-associated logger, not this instance's one
        if executor.id in self._executors:
            m = ("There already is executor associated with request id '%s' in FDTD container! Duplicate "
                 "request? Something wasn't not cleared up properly?" % executor.id)
            raise FDTDException(m)
        else:
            self._executorsLock.acquire(True)
            self._executors[executor.id] = executor
            self._executorsLock.release()
            executor.logger.debug("%s added to the FDTD executors container." % executor)
                        
            
            
    def removeExecutor(self, executor):
        # when logging, use the request-associated logger, not this instance's one
        self._executorsLock.acquire(True)
        try:
            del self._executors[executor.id]
        except KeyError:
            executor.logger.error("Executor id '%s' not present in the FDTD executors container." % executor.id)
        else:
            executor.logger.debug("%s removed from the FDTD executors container." % executor)
        self._executorsLock.release()
        
            
    
    def killProcess(self, id, logger):
        """id is a key into self._executors pool"""
        
        logger.debug("Processing clean up / process kill request for transfer id '%s' ..." % id)
        if id in self._executors:
            executor = self._executors[id]
            m = self._killProcess(executor, logger)
            logger.info(m)
            # if no exception occurred in ._killProcess, then remove the executor
            # (and the exception will be propagated) 
            self.removeExecutor(executor)
            if executor.port:
                self.releasePort(executor.port)
        else:
            m = "No such process/action id '%s' to kill (probably already finished)." % id
            logger.error(m)
        return m
        
            

    def start(self):
        objServiceName = self.service.__class__.__name__
        uri = self.pyroDaemon.connect(self.service, objServiceName)
        self.logger.info("%s waiting for requests ... ('%s' uri: '%s')" %
                         (self._name, objServiceName, uri))
        # the flow stops at this call - can be interrupted by a signal
        # (and handler is called) when running as a proper daemon in production
        # or from Keyboard (development mode)
        self.pyroDaemon.requestLoop()



    def _killProcess(self, executor, logger):
        """Method to perform cleaning up / killing of running processes.
           if the process runs, check process's killTimeout, wait that
           time if it finishes, if not kill it.
           The issues is e.g. FDT server may still be flushing its buffers.
           The logger variable may either be associated with a separate PYRO
           received request, i.e. associated with CleanupProcessesAction
           or if this method is called from within this same class, it would
           be basically self.logger
        """        
        logger.debug("Going to poll state: %s ..." % executor)

        e = executor
        if e.killTimeout > 0:
            waitIter = 4
            waitIterTime = e.killTimeout / waitIter
            
            for i in range(waitIter):
                if e.proc.poll() > -1:
                    returnCode = e.proc.wait()
                    m = ("Process PID: %s finished, returncode: '%s'\nlogs:\n%s" %
                         (e.proc.pid, returnCode, e.getLogs()))
                    return m
                else:
                    logger.debug("Process PID: %s still runs ..." % e.proc.pid)
                time.sleep(waitIterTime)
            
            logger.warn("Process PID: %s still has not finished (timeout: %s), "
                        "going to kill it ..." % (e.proc.pid, e.killTimeout))
        else:
            logger.warn("Going to kill process PID: %s, kill wait timeout is %s ..." %
                        (e.proc.pid, e.killTimeout))
            
        # python 2.4.3 Popen object has no attribute kill - can't do executor.proc.kill()
        # have to kill via external kill OS command
        try:
            # TODO
            # SIGTERM doesn't stop properly all client threads in
            # AuthService GSIBaseServer, have to use brute force SIGKILL
            if e.userName:
                opt = dict(pid = e.proc.pid, sudouser = e.userName)
                command = self.conf.get("killCommandSudo") % opt
            else:
                opt = dict(pid = e.proc.pid)
                command = self.conf.get("killCommand") % opt

            killExec = Executor(e.id, command, blocking = True, logger = logger)
            output = killExec.execute()
        except ExecutorException, ex:
            m = ("Error when killing process PID: %s (kill process: %s), "
                 "reason: %s\nlogs from the killed-attempt process:\n%s" %
                 (e.proc.pid, killExec, ex, e.getLogs())) 
            logger.error(m) # will be logged locally with the fdtd daemon
            raise FDTDException(m) # will be propagated and logged with remote fdtcp client
        else:
            m = ("%s killed, returncode: '%s'\nlogs:\n%s" %
                 (e, e.proc.wait(), e.getLogs()))
            return m
            

    
    def shutdown(self):
        self.logger.warn("Shutting down %s ..." % self._name)
        
        # do this as soon as possible, before PYRO daemon goes down
        # so that clients connected beyond this point are notified
        # by receiving PyroError for response
        self.service.setStop()
        
        self.pyroDaemon.shutdown(True)
        self.pyroDaemon.closedown() # immediately releases port
        self.logger.warn("PYRO service stopped.")
        self.logger.warn("%s stopped, shutdown sequence finished." % self._name)
        
        self.logger.warn("%s associated processes running." % len(self._executors))
        self._executorsLock.acquire()
        try:
            for id in self._executors:
                # here calling ._killProcess with the FDTD instance logger
                # this operation is not related to any request
                m = self._killProcess(self._executors[id], self.logger)
                self.logger.info(m)
        except FDTDException, ex:
            self.logger.error(ex)
        self._executorsLock.release()
                        
        
            
    def _signalHandler(self, signum, frame):
        # TODO
        # distinguish which signal / action to take - whether to ignore
        # or force shutdown (when there is a job in progress)
        self.logger.fatal("Signal %s caught, shutting down ..." % signum)
        # raise exception rather than calling .shutdown() directly, this way
        # it can be only shutdown from one place
        raise ServiceShutdownBySignal()




class ConfigFDTD(Config):
    """Class holding various options and settings which are either predefined
       in the configuration file, overriding from command line options is
       considered.
    """

    _mandatoryInt = ["port", "portAuthService", "fdtSendingClientKillTimeout",
                     "fdtServerLogOutputTimeout", "fdtReceivingServerKillTimeout",
                     "authServiceLogOutputTimeout"]
    _mandatoryStr = ["fdtSendingClientCommand", "fdtReceivingServerCommand",
                     "debug", "portRangeFDTServer", "transferSeparateLogFile",
                     "fdtServerLogOutputToWaitFor", "authServiceLogOutputToWaitFor",
                     "authServiceCommand", "killCommandSudo", "killCommand",
                     "daemonize", "pidFile"]

    def __init__(self, args):
        # 1 - shall point to the same directory
        currDir = os.path.abspath(__file__).rsplit(os.sep, 1)[0]
        currDirConfig = os.path.join(currDir, "fdtd.conf")
        # consider only config file being in the same directory
        # as well as in the system config directory location
        locations = [currDirConfig, "/etc/fdtcp/fdtd.conf"]
        self.usage = None
        Config.__init__(self, args, locations)

        

    def processCommandLineOptions(self, args):
        """This method gets called from base class"""
        help = "debug output level, for possible values see the config file"
        self._parser.add_option("-d", "--debug", help = help)
        help = "port number on which to start local fdtd service"
        self._parser.add_option("-p", "--port", help = help)
        help = "configuration file for fdtd service"
        self._parser.add_option("-c", "--config", help = help)
        help = "print this help"
        self._parser.add_option("-h", "--help", help = help, action = 'help')
        help = "specify hostname of this machine"
        self._parser.add_option("-H", "--hostname", help = help)
        help = "output log file"
        self._parser.add_option("-l", "--logFile", help = help)
        help = "run the service on the background as daemon process"
        self._parser.add_option("-a", "--daemonize", action="store_true", help = help)
        help = "file to store PID of the daemon process (when running with daemonize)"
        self._parser.add_option("-i", "--pidFile", help = help)

        # opts - new processed options, items defined above as attributes
        # args - remainder of the input array
        opts, args = self._parser.parse_args(args = args)

        self._options = opts
        
        


class AuthService(object):
    """Class for encapsulating process of AuthService - Grid authentication 
       service - runs in a single instance per fdtd
       Shutdown of the process is taken care of by FDTD instance, once this
       process is started, it is registered with FDTD which will kill it
       when it goes down.
    """
    
    # TODO
    # may need to flush its buffers with output, though there should not
    # significant amount of data, but this would have to done either from
    # Java or something will have automatically poll this AuthService executor ...
    
    def __init__(self, fdtd, conf, logger):
        self.fdtd = fdtd
        self.conf = conf
        self.logger = logger
        
        self.logger.debug("Creating instance of AuthService ...")
        self.options = {}
        self.options["port"] = self.conf.get("portAuthService")
        command = self.conf.get("authServiceCommand") % self.options
        toWaitFor = self.conf.get("authServiceLogOutputToWaitFor")
        timeout = self.conf.get("authServiceLogOutputTimeout")
        self.executor = Executor("AuthService", command = command, blocking = False,
                                 caller = self.fdtd, logOutputToWaitFor = toWaitFor,
                                 logOutputWaitTime = timeout, logger = self.logger)
        try:
            output = self.executor.execute()
            self.logger.debug(output)
        except ExecutorException, ex:
            m = "Could not start AuthService, reason: %s" % ex
            raise AuthServiceException(m)

     

def daemonize(conf, logger):
    """Store pid of the current process into pidFile and fork the daemon process (FDTD).""" 
    
    logger.info("Preparing for daemonization (parent process PID: '%s') ..." % os.getpid())
    
    # check that there is a log defined, otherwise fail - need to
    # redirect stdout, stderr stream into this file
    if not conf.get("logFile"):
        logger.fatal("No log file defined, necessary when running as daemon, exit.")
        logger.close()
        sys.exit(1)
    
    pidFile = conf.get("pidFile")
    # try opening the file for append - if exists - fail: fdtd.py might be running
    # or the file was left behind
    if os.path.isfile(pidFile):
        logger.fatal("File '%s' exists, can't start, remove it first." % pidFile)
        logger.close()
        sys.exit(1)
        
    # check if the pidFile is writeable
    try:
        pidFileDesc = open(pidFile, 'w')
        pidFileDesc.close()
    except IOError, ex:
        logger.fatal("Can't access PID file '%s', reason: %s" % (pidFile, ex))
        logger.close()
        sys.exit(1)
    
    # daemonization forking ...
    if os.fork() != 0:
        # exit parent code
        sys.exit(0)
    
    # decouple from parent environment
    os.setsid()
    os.umask(0)
    # don't change current working directory (os.chdir("/"))

    # fork again so we are not a session leader
    if os.fork() != 0:
        sys.exit(0)

    # output streams redirection into the log file
    # log file is already used by logger, concurrent writes may get messy ...
    # ideally there however should not be any logging into streams from now on ...
    logger.debug("Redirecting stdout, stderr, stdin streams ...")
    logFile = file(conf.get("logFile"), "a+", 0) # buffering - 0 (False)
    devNull = file("/dev/null", 'r')
    os.dup2(logFile.fileno(), sys.stdout.fileno())
    os.dup2(logFile.fileno(), sys.stderr.fileno())
    os.dup2(devNull.fileno(), sys.stdin.fileno())
    
    # finally - the daemon process code, first store it's PID into file
    pid = os.getpid()
    logger.info("Running as daemon process: PID: '%s' (forked), PID file: '%s'" % (pid, pidFile))
    pidFileDesc = open(pidFile, 'w')
    pidFileDesc.write(str(pid))
    pidFileDesc.close()

    startApplication(conf, logger)
    


def startApplication(conf, logger):
    apMonDestConf = conf.get("apMonDestinations")
    apMonDestinations = tuple(apMonDestConf.split(','))
    logger.info("Initializing MonALISA ApMon, destinations: %s ..." % (apMonDestinations,))
    apMon = apmon.ApMon(apMonDestinations)
    apMon.enableBgMonitoring(True)
    
    # use DNS names rather than IP address
    Pyro.config.PYRO_DNS_URI = True
    
    daemon = None
    try:
        try:
            daemon = FDTD(conf, apMon, logger)
            authService = AuthService(daemon, conf, logger)
            daemon.start()
        except AuthServiceException, ex:
            logger.fatal("Exception during AuthService startup, reason: %s" % ex)
        except (FDTDException, ), ex:
            logger.fatal("Exception during FDTD initialization, reason: %s" % ex)
        except KeyboardInterrupt:
            logger.fatal("Interrupted from keyboard ...")
        except ServiceShutdownBySignal:
            logger.fatal("Shutdown exception signal received.")
        except ServiceShutdownBySignalForced:
            logger.fatal("Shutdown exception signal (forced) received.")
        except Exception, ex:
            logger.fatal("Exception was caught ('%s'), reason: %s"
                          % (ex.__class__.__name__, ex), traceBack = True)
    finally:
        if daemon:
            daemon.shutdown()
        apMon.free()
        
        # if daemonize, pidFile should have been created, delete it now when 
        # shutting down
        if conf.get("daemonize"):
            pidFile = conf.get("pidFile")
            logger.info("Deleting the PID file '%s' ... " % pidFile)
            try:
                os.remove(pidFile)
                logger.debug("File '%s' removed." % pidFile)
            except OSError, ex:
                logger.error("Could not remove PID file '%s', reason: %s" % (pidFile, ex))
            
        logger.close()


      
def main():
    # all values and action information held in the conf object
    optBackup = sys.argv[:]
    try:
        conf = ConfigFDTD(sys.argv[1:])
        conf.sanitize()
    except ConfigurationException, ex:
        print "fdtd failed to start, reason: %s" % ex
        sys.exit(1)
            
    logger = Logger(name = "fdtd", logFile = conf.get("logFile"), level = conf.get("debug"))
    logger.info("fdtd starting ...")
    logger.debug("Search sys.path: '%s'" % sys.path)
    logger.debug("PYRO_STORAGE: '%s'" % os.environ.get("PYRO_STORAGE"))
    
    logger.debug("Input command line arguments: '%s'" % optBackup)
    logger.debug("Configuration values (processed): '%s'" % conf._options)
    
    # daemonization
    if conf.get("daemonize"):
        daemonize(conf, logger)
    else:
        logger.info("Starting the service on foreground ...")
        startApplication(conf, logger)

        

if __name__ == "__main__":
    main()
